home *** CD-ROM | disk | FTP | other *** search
/ Columbia Kermit / kermit.zip / newsgroups / misc.20020314-20021006 / 000028_ishikawa@yk.rim.or.jp_Mon Apr 8 16:49:57 EDT 2002.msg < prev    next >
Text File  |  2020-01-01  |  13KB  |  371 lines
  1. Article: 13299 of comp.protocols.kermit.misc
  2. Path: newsmaster.cc.columbia.edu!panix!jfk3-feed1.news.algx.net!dca6-feed2.news.algx.net!allegiance!newsfeed1.cidera.com!Cidera!newsfeed.media.kyoto-u.ac.jp!newsfeed.rim.or.jp!news.rim.or.jp!not-for-mail
  3. From: Ishikawa <ishikawa@yk.rim.or.jp>
  4. Newsgroups: comp.protocols.kermit.misc
  5. Subject: Re: a bug on GNU/linux: speed reset to unintended value occasionally.
  6. Date: Tue, 09 Apr 2002 02:35:48 +0900
  7. Organization: Ye 'Ol Disorganized NNTPCache groupie
  8. Lines: 347
  9. Message-ID: <3CB1D4F3.10D79B1F@yk.rim.or.jp>
  10. References: <3CAFF81C.8039CBF8@yk.rim.or.jp> <a8q34m$l3l$1@watsol.cc.columbia.edu>
  11. NNTP-Posting-Host: pl251.nas911.n-yokohama.nttpc.ne.jp
  12. Mime-Version: 1.0
  13. Content-Type: text/plain; charset=iso-2022-jp
  14. Content-Transfer-Encoding: 7bit
  15. X-Trace: news.rim.or.jp 1018287351 58894 210.139.98.251 (8 Apr 2002 17:35:51 GMT)
  16. X-Complaints-To: root@rim.or.jp
  17. NNTP-Posting-Date: Mon, 8 Apr 2002 17:35:51 +0000 (UTC)
  18. X-Mailer: Mozilla 4.77 [en] (X11; U; Linux 2.4.17 i686)
  19. X-Accept-Language: ja, en
  20. Cache-Post-Path: duron!unknown@localhost
  21. X-Cache: nntpcache 2.3.3 (see http://www.nntpcache.org/)
  22. Xref: newsmaster.cc.columbia.edu comp.protocols.kermit.misc:13299
  23.  
  24. >
  25. > Thank you for the excellent report.  I was ready to start
  26. > a big debugging session, only to find that my Linux PC won't
  27. > turn on any more.  There's not much I can do at the moment
  28. > without a Linux PC where I have hands-on access to the serial
  29. > port and can hook up test equipment.
  30.  
  31. Murphy's law strikes!
  32.  
  33. Anyway, here is an additional report I prepared...
  34.  
  35. ---
  36.  
  37. Thank you for quick response.
  38.  
  39. I posted the repot on the weekend, and so I thought I needed to
  40. wait until later Monday, etc..
  41. A pleasant surprise to see a quick reply on weekend.
  42.  
  43. Anyway, I should not have mentioned CISCO in the bug report.
  44. CISCO router DOES use the traditional bytesize, parity setting, etc.
  45. and has nothing to do with the reported bug that seems to be
  46. triggered by "set parity hardware".
  47. You are right. If CISCO uses such strange communcation setting,
  48. a lot more people would have requested the 8E1 settings in KERMIT
  49. long before.
  50.  
  51. Anyway, to give a better background
  52. information, here is a brief description of the
  53. hardware configuration where the problem was observed.
  54. The proprietary hardware box that is connected to a
  55. linux PC at the office uses the 8E1 datasize setting.
  56.  
  57. At the office:
  58.    PC   <----- serial cable --------------> HW box.
  59.    RedHat 7.2                            8E1 (19200/38400 bps)
  60.  ( It seems the kernel is 2.4.7).
  61.  
  62. At home
  63.    PC  <--- serial port ---> nothing is connected at the moment.
  64.    Debian 2.2rx (x bein 5 or 6: I have upgraded from r2 on my own.)
  65.    Kernel is 2.4.17.
  66.  
  67.  
  68. Too bad that your linux PC no longer boots?
  69. Murphy's law strikes at the most inconvenient time.
  70.  
  71. While you try to resurrect your linux PC,
  72. I have dug into the problem on my own.
  73. The following discovery
  74. might help you in locating the cause of the bug.
  75.  
  76. Here are a few findings. (Debugging was done on the
  77. RedHat linux PC at the office.)
  78.  
  79. - The kermit binary on my RedHat PC seems to be
  80.   the one downloaded from Columbia. (Not someone's
  81.   RPM.)
  82.  
  83. - I have found a certain command sequence that shows
  84.   the bug repeatedly. (Shown below.)
  85.  
  86.   [ Also, nice thing is that I also found that if I don't
  87.     enable "set parity hardware", the flipping of speed
  88.     didn't occur with the above
  89.     mentioned sequence.
  90.     A key clue to find out where the bug might be. ]
  91.  
  92. - I ran "strace" to trace the system calls during the
  93.   above mentioned command sequence and found that
  94.   a call to ioctl() indeed switches speed to 2400 (B2400)!!!
  95.   (Shown below.)
  96.  
  97. - Since I have forgotten how to invoke the debug features of
  98.   kermit, I inserted fprintf(stderr, ...) statements
  99.   in strategic places and found the
  100.   statement that invokes ioctl with incorrect speed setting.
  101.  
  102. I think we are very close to finding the cause of the bug.
  103.  
  104. Now the details.
  105.  
  106. 1. The simplest sequence to find the bug on RedHat 7.2 PC
  107.  
  108. (I may have a .kermitrc file for the root account.
  109. I am not sure, but the speed setting of 38400 might
  110. suggest so.)
  111.  
  112. The following command sequence
  113. repeatedly showed the flipping of speed on RedHat 7.2.
  114.  
  115. # strace -o /tmp/t.out ./wermit
  116. C-Kermit 8.0.201, 8 Feb 2002, for Linux
  117.  Copyright (C) 1985, 2002,
  118.   Trustees of Columbia University in the City of New York.
  119. Type ? or HELP for help.
  120. (/home/ishikawa/KERMIT/) C-Kermit>set modem none
  121. (/home/ishikawa/KERMIT/) C-Kermit>set line /dev/ttyS0
  122. (/home/ishikawa/KERMIT/) C-Kermit>show comm
  123.  
  124. Communications Parameters:
  125.  Line: /dev/ttyS0, speed: 38400, mode: local, modem: none
  126.  Parity: none, stop-bits: (default) (8N1)
  127.  Duplex: full, flow: none, handshake: none
  128.  Carrier-watch: auto, close-on-disconnect: off
  129.  Lockfile: /var/lock/LCK..ttyS0
  130.  Terminal bytesize: 8, escape character: 28 (^\)
  131.  
  132.  Carrier Detect      (CD):  Off
  133.  Dataset Ready       (DSR): Off
  134.  Clear To Send       (CTS): On
  135.  Ring Indicator      (RI):  Off
  136.  Data Terminal Ready (DTR): On
  137.  Request To Send     (RTS): On
  138.  
  139. Type SHOW DIAL to see DIAL-related items.
  140. Type SHOW MODEM to see modem-related items.
  141.  
  142. (/home/ishikawa/KERMIT/) C-Kermit>set parity hardware
  143. (/home/ishikawa/KERMIT/) C-Kermit>show comm
  144. show comm
  145.  
  146. Communications Parameters:
  147.  Line: /dev/ttyS0, speed: 38400, mode: local, modem: none
  148.  Parity: hardware even, stop-bits: (default) (8E1)
  149.  Duplex: full, flow: none, handshake: none
  150.  Carrier-watch: auto, close-on-disconnect: off
  151.  Lockfile: /var/lock/LCK..ttyS0
  152.  Terminal bytesize: 8, escape character: 28 (^\)
  153.  
  154.  Carrier Detect      (CD):  Off
  155.  Dataset Ready       (DSR): Off
  156.  Clear To Send       (CTS): On
  157.  Ring Indicator      (RI):  Off
  158.  Data Terminal Ready (DTR): On
  159.  Request To Send     (RTS): On
  160.  
  161. Type SHOW DIAL to see DIAL-related items.
  162. Type SHOW MODEM to see modem-related items.
  163.  
  164. (/home/ishikawa/KERMIT/) C-Kermit>connect
  165. Connecting to /dev/ttyS0, speed 38400
  166.  Escape character: Ctrl-\ (ASCII 28, FS): enabled
  167. Type the escape character followed by C to get back,
  168. or followed by ? to see other options.
  169. CONNECT speed=38400       <--- a debug output of my own.
  170. ?Carrier required but not detected.
  171. ***********************************
  172.  Hint: To CONNECT to a serial device that
  173.  is not presenting the Carrier Detect signal,
  174.  first tell C-Kermit to:
  175.  
  176.    SET CARRIER-WATCH OFF
  177.  
  178. ***********************************
  179.  
  180. CI: error return here ckucns.c 1367 <--- a debug output of my own.
  181. (/home/ishikawa/KERMIT/) C-Kermit>show comm
  182.  
  183. ***** Now the speed is flipped into 2400 !!! ****
  184. ***** See below!
  185.  
  186. Communications Parameters:
  187.  Line: /dev/ttyS0, speed: 2400, mode: local, modem: none
  188.  Parity: hardware even, stop-bits: (default) (8E1)
  189.  Duplex: full, flow: none, handshake: none
  190.  Carrier-watch: auto, close-on-disconnect: off
  191.  Lockfile: /var/lock/LCK..ttyS0
  192.  Terminal bytesize: 8, escape character: 28 (^\)
  193.  
  194.  Carrier Detect      (CD):  Off
  195.  Dataset Ready       (DSR): Off
  196.  Clear To Send       (CTS): On
  197.  Ring Indicator      (RI):  Off
  198.  Data Terminal Ready (DTR): On
  199.  Request To Send     (RTS): On
  200.  
  201. Type SHOW DIAL to see DIAL-related items.
  202. Type SHOW MODEM to see modem-related items.
  203.  
  204. (/home/ishikawa/KERMIT/) C-Kermit>quit
  205. quit
  206. Closing /dev/ttyS0...OK
  207. [root@dell-w2k-note KERMIT]#
  208.  
  209. 2. The strace output.
  210.  
  211.    The strace output captured during the above command run.
  212.  
  213.    I only show the relevant portion.
  214.    Please note the line marked with "*=>", i.e,
  215.    *=> ioctl(3, 0x5403, {B2400 -opost -isig -icanon -echo ...}) = 0
  216.  
  217.        ...
  218.     read(0, "connect", 1024)                = 7
  219.     write(1, "connect", 7)                  = 7
  220.     read(0, "\n", 1024)                     = 1
  221.     write(1, "\n", 1)                       = 1
  222.     time(NULL)                              = 1018263977
  223.     ioctl(0, 0x5401, {B38400 opost isig -icanon -echo ...}) = 0
  224.     ioctl(0, 0x5401, {B38400 opost isig -icanon -echo ...}) = 0
  225.     ioctl(0, 0x5403, {B38400 opost isig icanon -echo ...}) = 0
  226.     alarm(0)                                = 0
  227.     rt_sigaction(SIGALRM, {SIG_IGN}, {SIG_IGN}, 8) = 0
  228.     write(1, "Connecting to /dev/ttyS0, speed "..., 39) = 39
  229.     write(1, " Escape character: Ctrl-\\ (ASCII"..., 51) = 51
  230.     write(1, "Type the escape character follow"..., 54) = 54
  231.     write(1, "or followed by ? to see other op"..., 40) = 40
  232.     ioctl(0, 0x5401, {B38400 opost isig icanon -echo ...}) = 0
  233.     ioctl(0, 0x5401, {B38400 opost isig icanon -echo ...}) = 0
  234.     ioctl(0, 0x5403, {B38400 -opost -isig -icanon -echo ...}) = 0
  235.     write(2, "CONNECT speed=38400\n", 20)   = 20
  236.     ioctl(3, 0x5401, {B38400 -opost -isig -icanon -echo ...}) = 0
  237.     ioctl(3, 0x5403, {B38400 -opost -isig -icanon -echo ...}) = 0
  238.     ioctl(3, 0x5401, {B38400 -opost -isig -icanon -echo ...}) = 0
  239.     ioctl(3, 0x5402, {B38400 -opost -isig -icanon -echo ...}) = 0
  240.     ioctl(3, 0x5401, {B38400 -opost -isig -icanon -echo ...}) = 0
  241. *=> ioctl(3, 0x5403, {B2400 -opost -isig -icanon -echo ...}) = 0
  242.     rt_sigaction(SIGINT, {SIG_IGN}, {0x80e666c, [INT],
  243. SA_RESTART|0x4000000}, 8) = 0
  244.     rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_IGN}, 8) = 0
  245.     ioctl(3, 0x5415, [TIOCM_DTR|TIOCM_RTS|TIOCM_CTS|0x4000]) = 0
  246.     ioctl(0, 0x5401, {B38400 -opost -isig -icanon -echo ...}) = 0
  247.     ioctl(0, 0x5403, {B38400 opost isig icanon -echo ...}) = 0
  248.     write(1, "?Carrier required but not detect"..., 36) = 36
  249.     write(1, "********************************"..., 36) = 36
  250.     write(1, " Hint: To CONNECT to a serial de"..., 42) = 42
  251.     write(1, " is not presenting the Carrier D"..., 46) = 46
  252.     write(1, " first tell C-Kermit to:\n\n", 26) = 26
  253.     write(1, "   SET CARRIER-WATCH OFF\n\n", 26) = 26
  254.     write(1, "********************************"..., 37) = 37
  255.     write(2, "CI: error return here ckucns.c 1"..., 36) = 36
  256.     ioctl(0, 0x5401, {B38400 opost isig icanon -echo ...}) = 0
  257.     ioctl(0, 0x5403, {B38400 opost isig -icanon -echo ...}) = 0
  258.     getpgrp()                               = 30970
  259.     ioctl(1, 0x540f, [30970])               = 0
  260.     ...
  261.  
  262. 3. Where the call takes place.
  263.  
  264.    After I captured the above log,
  265.    I tried inserting fprintf() in some places and
  266.    see if I can identify the statement that calls the
  267.    ioctl() with incorrect speed setting.
  268.    It was a trial and error efforts, but in the end,
  269.    I could identify the statement.
  270.  
  271.    Near the end of function ttvt() in the file  ckutio.c,
  272.    there is a code that looks like the following
  273.    The code below is AFTER my insertion of fprintf() and
  274.    my own comment.
  275.  
  276.    The "tcsetattr(ttyfd, TCSADRAIN, &tttvt)" call
  277.    is the problematic one.
  278.  
  279.    ...
  280.   #endif /* VEOL */
  281.  
  282.   #ifdef Plan9
  283.       if (p9ttyparity('n') < 0)
  284.  return -1;
  285.   #else
  286.  
  287.       fprintf(stderr,"CI: ttvt called %s, %d\n", __FILE__, __LINE__);
  288.  
  289.  
  290.   #ifdef BSD44ORPOSIX
  291.       errno = 0;
  292.   #ifdef BEOSORBEBOX
  293.       tttvt.c_cc[VMIN] = 0;  /* DR7 can only poll. */
  294.   #endif /* BEOSORBEBOX */
  295.  
  296.       fprintf(stderr,"CI: ttvt called %s, %d\n", __FILE__, __LINE__);
  297.  
  298.       /* CI suspicious. */
  299.       x = tcsetattr(ttyfd,TCSADRAIN,&tttvt);
  300.  
  301.       fprintf(stderr,"CI: ttvt called %s, %d\n", __FILE__, __LINE__);
  302.  
  303.       debug(F101,"ttvt BSD44ORPOSIX tcsetattr","",x);
  304.       if (x < 0) {
  305.    debug(F101,"ttvt BSD44ORPOSIX tcsetattr errno","",errno);
  306.    return(-1);
  307.       }
  308.   #else /* ATTSV */
  309.       fprintf(stderr,"CI: tthflow called %s, %d\n", __FILE__, __LINE__);
  310.  
  311.  
  312.  
  313.  
  314. The tcsetattr() call that follows "Suspicous" comment
  315. is the culprit.
  316.  
  317. 4. My educated guess.
  318.  
  319.    Either
  320.    (a)  tttvt is not initialized correctly, or
  321.    (b)  when the hardware parity is on,
  322.         a few places where the variable hwparity
  323.         is referenced and tttvt is updated
  324.         may corrupt the data in tttvt in an unexpected
  325.        way.
  326.  
  327.    Since the bug appears only when "set parity hardware"
  328.    (well, at least on RedHat), I guess the cause
  329.    (b) is more likely although I don't rule out
  330.    (a) also. Maybe both?
  331.  
  332.  
  333. Hope this helps.
  334.  
  335.  
  336.  
  337. PS: BTW, one of these days, we can probably use one instance of Kermit
  338. to simulate a device that uses 8E1 datasize setting.  The
  339. implementation seems to work more or less correctly albeit some bugs
  340. like the one I have found out.
  341.  
  342. The current implementaions is good enough to test 8E1 data setting on
  343. another platform, I think.  Actually, this is how I tested the solaris
  344. 7 problems a couple of years ago. I connected the two ports of a
  345. solaris 7 for x86 PC and tested file transfer, etc. and found
  346. that Solaris needed to use POSIX tty handling or something.
  347.  
  348. PPS: Your suggestion of connecting the live device
  349. at the end of the cable may be a valid one.
  350.  
  351. Unfortunately, the particular hardware box
  352. has a nasty habit of not initializing the
  353. serial terminal until about 40 or 50 seconds
  354. after power up.
  355. And the only way for me to tell if the hardware box
  356. booted successfully is to
  357. see a short greeting message that appears
  358. on the serial line.
  359. ONLY THEN I can begin typing certain commands from
  360. kermit into the hardware.
  361. So I needed to monitor this greeting message
  362. and in so doing, I was forced to monitor
  363. the serial line  BEFORE
  364. the signals from the hardware box come alive...
  365. Hmm...
  366.  
  367.  
  368.  
  369.  
  370.  
  371.